Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve klog (client-go logs) handling #11632

Merged
merged 2 commits into from
Nov 28, 2023
Merged

Improve klog (client-go logs) handling #11632

merged 2 commits into from
Nov 28, 2023

Conversation

alpeb
Copy link
Member

@alpeb alpeb commented Nov 17, 2023

Currently log entries in the go-based controllers originated in the client-go library are only visible if the controller’s log level is debug. If the log level is lower (info, warn, error), we lose possibly important information. If the log level is debug we receive a lot of entries, mostly irrelevant.

client-go uses klog for its logs, which relies on logr as its backend, which is just an interface allowing different implementations, one of which is logrus, which we use in our controllers. So in this change we bring the logrusr library which implements logrus for logr.

The verbosity level for klog is also tweaked a little bit, according to k8s logging conventions.

Also, given that logging output is now handled completely by logrus, some of the klog config flags are no longer required.

As an example of the new behavior in the proxy-injector logs, when removing the RBAC to list pods, we now see the complaints coming from client-go, which were invisible before at info level:

time="2023-11-17T20:58:30Z" level=info msg="running version dev-94ad50cd-alpeb"
time="2023-11-17T20:58:30Z" level=info msg="starting admin server on :9995"
time="2023-11-17T20:58:30Z" level=info msg="listening at :8443"
time="2023-11-17T20:58:30Z" level=info msg="waiting for caches to sync"
time="2023-11-17T20:58:30Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:30Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:32Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:32Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:34Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:34Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"

time="2023-11-17T20:58:40Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:40Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:48Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:48Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:59:05Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:59:05Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:59:30Z" level=fatal msg="failed to sync caches"

Currently log entries in the go-based controllers originated in the client-go library are only visible if the controller’s log level is `debug`. If the log level is lower (`info`, `warn`, `error`), we lose possibly important information. If the log level is `debug` we receive a lot of entries, mostly irrelevant.

client-go uses [klog](https://github.com/kubernetes/klog) for its logs, which relies on [logr](https://github.com/go-logr/logr) as its backend, which is just an interface allowing different implementations, one of which is logrus, which we use in our controllers. So in this change we bring the [logrusr](https://github.com/bombsimon/logrusr) library which implements logrus for logr.

The verbosity level for klog is also tweaked a little bit, according to k8s [logging conventions](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md).

Also, given that logging output is now handled completely by logrus, some of the klog config flags are no longer required.

As an example of the new behavior in the proxy-injector logs, when removing the RBAC to list pods, we now see the complaints coming from client-go, which were invisible before at `info` level:

```console
time="2023-11-17T20:58:30Z" level=info msg="running version dev-94ad50cd-alpeb"
time="2023-11-17T20:58:30Z" level=info msg="starting admin server on :9995"
time="2023-11-17T20:58:30Z" level=info msg="listening at :8443"
time="2023-11-17T20:58:30Z" level=info msg="waiting for caches to sync"
time="2023-11-17T20:58:30Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:30Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:32Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:32Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:34Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:34Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"

time="2023-11-17T20:58:40Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:40Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:48Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:48Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:59:05Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:59:05Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:59:30Z" level=fatal msg="failed to sync caches"
```
@alpeb alpeb requested a review from a team as a code owner November 17, 2023 22:47
pkg/flags/flags.go Outdated Show resolved Hide resolved
@alpeb alpeb merged commit b438ec4 into main Nov 28, 2023
33 checks passed
@alpeb alpeb deleted the alpeb/client-go-logs branch November 28, 2023 14:25
mateiidavid added a commit that referenced this pull request Nov 30, 2023
This edge release introduces new configuration values in the identity
controller for client-go's `QPS` and `Burst` settings. Default values for these
settings have also been raised from `5` (QPS) and `10` (Burst) to `100` and
`200` respectively.

* Added `namespaceSelector` fields for the tap-injector and jaeger-injector
  webhooks. The webhooks are now configured to skip `kube-system` by default
  ([#11649]; fixes [#11647]) (thanks @mikutas!)
* Added the ability to configure client-go's `QPS` and `Burst` settings in the
  identity controller ([#11644])
* Improved client-go logging visibility throughout the control plane's
  components ([#11632])
* Introduced `PodDisruptionBudgets` in the linkerd-viz Helm chart for tap and
  tap-injector ([#11628]; fixes [#11248]) (thanks @mcharriere!)

[#11649]: #11649
[#11647]: #11647
[#11644]: #11644
[#11632]: #11632
[#11628]: #11628
[#11248]: #11248

Signed-off-by: Matei David <[email protected]>
@mateiidavid mateiidavid mentioned this pull request Nov 30, 2023
mateiidavid added a commit that referenced this pull request Dec 1, 2023
This edge release introduces new configuration values in the identity
controller for client-go's `QPS` and `Burst` settings. Default values for these
settings have also been raised from `5` (QPS) and `10` (Burst) to `100` and
`200` respectively.

* Added `namespaceSelector` fields for the tap-injector and jaeger-injector
  webhooks. The webhooks are now configured to skip `kube-system` by default
  ([#11649]; fixes [#11647]) (thanks @mikutas!)
* Added the ability to configure client-go's `QPS` and `Burst` settings in the
  identity controller ([#11644])
* Improved client-go logging visibility throughout the control plane's
  components ([#11632])
* Introduced `PodDisruptionBudgets` in the linkerd-viz Helm chart for tap and
  tap-injector ([#11628]; fixes [#11248]) (thanks @mcharriere!)

[#11649]: #11649
[#11647]: #11647
[#11644]: #11644
[#11632]: #11632
[#11628]: #11628
[#11248]: #11248

Signed-off-by: Matei David <[email protected]>
olix0r pushed a commit that referenced this pull request Dec 6, 2023
* Improve klog (client-go logs) handling

Currently log entries in the go-based controllers originated in the client-go library are only visible if the controller’s log level is `debug`. If the log level is lower (`info`, `warn`, `error`), we lose possibly important information. If the log level is `debug` we receive a lot of entries, mostly irrelevant.

client-go uses [klog](https://github.com/kubernetes/klog) for its logs, which relies on [logr](https://github.com/go-logr/logr) as its backend, which is just an interface allowing different implementations, one of which is logrus, which we use in our controllers. So in this change we bring the [logrusr](https://github.com/bombsimon/logrusr) library which implements logrus for logr.

The verbosity level for klog is also tweaked a little bit, according to k8s [logging conventions](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md).

Also, given that logging output is now handled completely by logrus, some of the klog config flags are no longer required.

As an example of the new behavior in the proxy-injector logs, when removing the RBAC to list pods, we now see the complaints coming from client-go, which were invisible before at `info` level:

```console
time="2023-11-17T20:58:30Z" level=info msg="running version dev-94ad50cd-alpeb"
time="2023-11-17T20:58:30Z" level=info msg="starting admin server on :9995"
time="2023-11-17T20:58:30Z" level=info msg="listening at :8443"
time="2023-11-17T20:58:30Z" level=info msg="waiting for caches to sync"
time="2023-11-17T20:58:30Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:30Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:32Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:32Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:34Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:34Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"

time="2023-11-17T20:58:40Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:40Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:58:48Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:58:48Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:59:05Z" level=info msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope"
time="2023-11-17T20:59:05Z" level=error msg="pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="<nil>"
time="2023-11-17T20:59:30Z" level=fatal msg="failed to sync caches"
```
olix0r added a commit that referenced this pull request Dec 6, 2023
* 6a07e2c Add ability to configure client-go's `QPS` and `Burst` settings (#11644)
* 64bccd9 Improve klog (client-go logs) handling (#11632)
* 284d76b service-mirror: support gateway resolving to multiple addresses (#11499)
* 0a72f1f Add imagePullSecrets to the multicluster chart. (#11287)
@olix0r olix0r mentioned this pull request Dec 6, 2023
olix0r added a commit that referenced this pull request Dec 7, 2023
* 0a72f1f Add imagePullSecrets to the multicluster chart. (#11287)
* 284d76b service-mirror: support gateway resolving to multiple addresses (#11499)
* 64bccd9 Improve klog (client-go logs) handling (#11632)
* 6a07e2c Add ability to configure client-go's `QPS` and `Burst` settings (#11644)
* e294c78 Bump prometheus to v2.48.0 (#11633)
* b24b0e97c stable-2.14.6
olix0r added a commit that referenced this pull request Dec 7, 2023
* 0a72f1f Add imagePullSecrets to the multicluster chart. (#11287)
* 284d76b service-mirror: support gateway resolving to multiple addresses (#11499)
* 64bccd9 Improve klog (client-go logs) handling (#11632)
* 6a07e2c Add ability to configure client-go's `QPS` and `Burst` settings (#11644)
* e294c78 Bump prometheus to v2.48.0 (#11633)
* b24b0e97c stable-2.14.6
olix0r added a commit that referenced this pull request Dec 7, 2023
stable-2.14.6

* 0a72f1f Add imagePullSecrets to the multicluster chart. (#11287)
* 284d76b service-mirror: support gateway resolving to multiple addresses (#11499)
* 64bccd9 Improve klog (client-go logs) handling (#11632)
* 6a07e2c Add ability to configure client-go's `QPS` and `Burst` settings (#11644)
* e294c78 Bump prometheus to v2.48.0 (#11633)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants